Migrate to use systemd events #217

jordigilh · 2022-07-29T00:23:05Z

Changes to use systemd events instead of relying on podman events.
Refactored systemd functions for clarity.
- Use fsNotify to capture file system changes in the .config/systemd/user/ directory; whenever a new change is made to this subdirectory, a routine in flotta receives the event and determines if it's an enabled or disabled service or something else. If it's an enabled service, for instance, it will add the service to the list of services to watch in the event listener, which will trigger an event from the dbus to notify the status of the service. It might look cumbersome but it's consistent with systemd:

One routine to watch for service files to monitor

Another routine to watch for status of those services.
Added the String() function to the Observer interface in configuration.go to help listing their names when debuging to display the observers registered instead of their memory references.

The services.json file remains as it is required to identify which service files are linked to a workload. We could get the information from systemd's service unit definition, but I don't want to extend this PR more than it is already, as it is starting to look like a behemoth, when it was supposed to be horse size.

Note: I tried to create an interface layer between dbus and the event listener so I could add unit tests. Unfortunately the initial effort translated into creating extra complexity because the dbus package is not providing interfaces. Suggestions are welcome.

jordigilh · 2022-07-29T01:27:07Z

Failing to properly configure the file permissions for volumes directory when run in a container. No issues when run in a VM. Investigating.

jordigilh · 2022-07-29T02:21:15Z

Failing to properly configure the file permissions for volumes directory when run in a container. No issues when run in a VM. Investigating.

Fixed in project-flotta/flotta-operator#290 . It is not a showstopper for this PR as it only impacts when running a custom RPM for the end to end tests.

internal/service/event_listener.go

internal/service/systemd.go

masayag · 2022-08-02T08:53:02Z

internal/service/event_listener.go

+func (e *EventListener) Add(workloadName string) {
+	name := fmt.Sprintf("%s.service", workloadName)
+	log.Debugf("Adding service for events %s", name)
+	if !e.set.Contains(name) {


In which case this might happen?
An attempt to add an already created service should be translated to a 'replace', but don't think we should meet this case.

it's a safeguard just in case the service was already part of the filter. In theory this should never happen based on the nominal flow. If a service is replaced it will be first removed and then readded by the events.

Ended up removing it with the new logic to watch for file system events. The case where the service could be added twice is not possible anymore.

masayag · 2022-08-02T08:54:19Z

internal/service/event_listener.go

+}
+
+func (e *EventListener) Add(workloadName string) {
+	name := fmt.Sprintf("%s.service", workloadName)


Pls pull fmt.Sprintf("%s.service", workloadName) to its method to be reused by Remove.

internal/service/event_listener.go

internal/workload/wrapper.go

masayag · 2022-08-02T10:20:46Z

internal/service/systemd.go

@@ -20,12 +20,20 @@ const (
 	DefaultRestartTimeout = 15
 	TimerSuffix           = ".timer"
 	ServiceSuffix         = ".service"
+	DefaultNameSeparator  = "-"


this isn't used.

Deleted. I wonder why no checks flagged this in the PR workflow.

masayag · 2022-08-02T10:31:37Z

internal/workload/wrapper.go

-
+	err := svc.Stop()
+	if err != nil {
+		log.Errorf("unable to stop service %s:%s", workloadName, err)


s/unable/Unable ?

masayag · 2022-08-02T10:31:42Z

internal/workload/wrapper.go

 	if err != nil {
-		return nil
+		log.Errorf("unable to remove service from serviceManager %s:%s", workloadName, err)


s/unable/Unable ?

eloycoto · 2022-08-02T14:39:33Z

@jordigilh what I mentioned yesterday regarding restarts:

Initialize all as normal, and deploy a workload; you will get the info here:
https://github.com/project-flotta/flotta-device-worker/blob/main/internal/metrics/workload.go#L55

After all the pods are running, you need to restart yggdrasild

systemctl restart yggdrasild

there is no notification that the workloadStarted, so the metrics are not updated at all, and it'll not scrape as it should.

jordigilh · 2022-08-02T15:15:50Z

@jordigilh what I mentioned yesterday regarding restarts:

Initialize all as normal, and deploy a workload; you will get the info here: https://github.com/project-flotta/flotta-device-worker/blob/main/internal/metrics/workload.go#L55

After all the pods are running, you need to restart yggdrasild
systemctl restart yggdrasild
there is no notification that the workloadStarted, so the metrics are not updated at all, and it'll not scrape as it should.

That's weird, I'm actually seeing it:

[root@fedora ~]# systemctl restart yggdrasild
[root@fedora ~]# Aug 02 11:14:39 fedora systemd[1]: Stopping yggdrasild.service - yggdrasil daemon...
Aug 02 11:14:39 fedora systemd[1]: yggdrasild.service: Killing process 1098 (device-worker) with signal SIGKILL.
Aug 02 11:14:39 fedora systemd[1]: yggdrasild.service: Deactivated successfully.
Aug 02 11:14:39 fedora systemd[1]: Stopped yggdrasild.service - yggdrasil daemon.
Aug 02 11:14:39 fedora systemd[1]: yggdrasild.service: Consumed 2.286s CPU time.
Aug 02 11:14:39 fedora systemd[1]: Started yggdrasild.service - yggdrasil daemon.
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 starting yggdrasild version 0.2.99
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 cannot start watching '/etc/yggdrasil/tags.toml': lstat /etc/yggdrasil/tags.toml: no such file or directory
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 listening on socket: @yggd-dispatcher-vTDVZH
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 cannot route message  123d34f8-412f-4eba-b718-eddffc010444 to directive: device
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 worker registered: {pid:1225 handler:device addr:@ygg-device-pqOEQv features:map[] detachedContent:false}
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: Data directory: /etc/yggdrasil/device
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: device config file: /etc/yggdrasil/device/device-config.json
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: started targetMetric for workload 'system'
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: started targetMetric for workload 'data transfer'
Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: Service for workload mylog started

Look at the last line:

Aug 02 11:14:39 fedora yggdrasild[1219]: [yggdrasild] 2022/08/02 11:14:39 /usr/libexec/yggdrasil/device-worker: Service for workload mylog started

Which is generated in this line:
https://github.com/project-flotta/flotta-device-worker/pull/217/files#diff-27f5b4db08ed174b7b18101c679d78c4dcf69db6fd8d6772f6a462f0fd6ae453R115

That's the only workload available for the device:

$> oc get edgedevice 4233c45699b644b79107306e74bccbc5  -ojsonpath='{.status.workloads}' | jq .
[
  {
    "lastTransitionTime": "2022-08-02T15:15:39Z",
    "name": "mylog",
    "phase": "Running"
  }
]

eloycoto · 2022-08-02T15:22:32Z

maybe the channel is not initialized at that time?

jordigilh · 2022-08-02T15:36:27Z

maybe the channel is not initialized at that time?

In that case the message should not have been received by the wrapper. In my case I'm testing with a workload and an edgedevice that has no metrics nor logs, so maybe that's why there are no other messages.
This is the log output when creating the workload in the first place:

Aug 02 11:33:41 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:41 /usr/libexec/yggdrasil/device-worker: updating configuration. New config: {"configuration":{"heartbeat":{"hardware_profile":{},"period_seconds":60},"metrics":{"receiver":{"request_num_samples":30000,"timeout_seconds":10}},"mounts":[]},"device_id":"4233c45699b644b79107306e74bccbc5","version":"206051","workloads":[{"name":"mylog","namespace":"default","specification":"containers:\n- image: docker.io/eloycoto/logexample\n  name: log\n  resources: {}\n"}]}
Aug 02 11:33:41 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:41 /usr/libexec/yggdrasil/device-worker: Old config: {"configuration":{"heartbeat":{"hardware_profile":{},"period_seconds":60},"metrics":{"receiver":{"request_num_samples":30000,"timeout_seconds":10}},"mounts":[]},"device_id":"4233c45699b644b79107306e74bccbc5","version":"205749"}
Aug 02 11:33:41 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:41 /usr/libexec/yggdrasil/device-worker: Creating service for mylog
Aug 02 11:33:41 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:41 /usr/libexec/yggdrasil/device-worker: writing new systemd file for 'container-mylog-log' on '/var/home/flotta/.config/systemd/user/container-mylog-log.service'
Aug 02 11:33:41 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:41 /usr/libexec/yggdrasil/device-worker: writing new systemd file for 'mylog' on '/var/home/flotta/.config/systemd/user/mylog.service'
Aug 02 11:33:42 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:42 /usr/libexec/yggdrasil/device-worker: Adding service for listener for mylog
Aug 02 11:33:42 fedora yggdrasild[3484]: [yggdrasild] 2022/08/02 11:33:42 /usr/libexec/yggdrasil/device-worker: Service for workload mylog started

Notice that there are no additional messages for metrics or logs after Service for workload mylog started

eloycoto · 2022-08-02T15:41:00Z

This is how I'm testing, and that should be received, but it's not.
https://drive.google.com/file/d/13sfK0L7eACQRhZInzAGfQWtPcKvMHZZ0/view?usp=sharing

jordigilh · 2022-08-02T23:11:44Z

This is how I'm testing, and that should be received, but it's not.

https://drive.google.com/file/d/13sfK0L7eACQRhZInzAGfQWtPcKvMHZZ0/view?usp=sharing

Confirmed. The problem is that the observers are not instantiated before the events are triggered. I will refactor the code to init the observers before the event listener is instantiated

jordigilh · 2022-08-04T01:52:29Z

@eloycoto can you try again?. I made it Eloy's fail-proof now :)

jordigilh · 2022-08-04T01:53:22Z

@masayag @tupyy significant refactoring made, so you might want to take another look at the whole thing.

cmd/device-worker/main.go

jordigilh · 2022-08-08T19:29:58Z

@masayag @eloycoto I've refactored the code and removed the FS Notify logic. Instead the event listener is now an Observer and taps into the device config as source of truth to be aware of which services to watch events for. Take a look at the last commit if you don't want to be bothered with the rest.

One thing that still bothers me is that we don't have any means to track other enabled user services, in case somehow a new service is added to the user outside of the agent's control.

tupyy · 2022-08-08T19:35:56Z

internal/service/event_listener.go

+	removed unitSubState = "removed"
+)
+
+var ()


pls remove it

eloycoto · 2022-08-26T09:46:01Z

cmd/device-worker/main.go

@@ -20,7 +20,8 @@ import (
 	os2 "github.com/project-flotta/flotta-device-worker/internal/os"
 	registration2 "github.com/project-flotta/flotta-device-worker/internal/registration"
 	"github.com/project-flotta/flotta-device-worker/internal/server"
-	workload2 "github.com/project-flotta/flotta-device-worker/internal/workload"
+	"github.com/project-flotta/flotta-device-worker/internal/service"
+	workload "github.com/project-flotta/flotta-device-worker/internal/workload"


this workload alias is not needed at all, no?

yeah, will remove it.

eloycoto · 2022-08-26T09:52:06Z

internal/service/event_listener.go

+	log.Infof("Starting DBus event listener")
+	conn, err := newDbusConnection(UserBus)
+	if err != nil {
+		return err


should be this formarted with a message?

I was not sure what would be the added value. Any suggestion to what to append?

ok I added this:

fmt.Errorf("error while starting event listener: %v", err)

eloycoto · 2022-08-26T09:53:28Z

internal/service/event_listener.go

+		svcName := DefaultServiceName(wl.Name)
+		if !e.contains(svcName) {
+			e.add(svcName)
+		}


The else conditions shouldn't raise an error?

Ok will add.

eloycoto · 2022-08-26T09:54:05Z

internal/service/event_listener.go

+				log.Debugf("Captured DBus event for %s: %v+", name, unit)
+				n, err := extractWorkloadName(name)
+				if err != nil {
+					log.Error(err)


I would add a wrapper error message here.

any suggestions? The message already contains the service name

eloycoto · 2022-08-26T09:54:30Z

internal/service/event_listener.go

+					continue
+				}
+				state := translateUnitSubStatus(unit)
+				log.Debugf("Systemd service for workload %s transitioned to sub state %s\n", n, state)


I will change the level to Info

It can be too verbose with a few workloads in place. I had them all in Info and it was dumping too much info. Keep in mind that for every change in the unit's status it will print this message, even when the changes are to be ignored because the new sub-state is not relevant.
I had this enabled earlier and it was dumping too much information.

The changes in state are already captured in here:

flotta-device-worker/internal/workload/wrapper.go

Line 363 in 623a857

log.Infof("Service for workload %s started", event.WorkloadName)

eloycoto · 2022-08-26T09:55:17Z

internal/service/event_listener.go

+					log.Debugf("Sending stop event to observer channel for workload %s", n)
+					e.eventCh <- &Event{WorkloadName: n, Type: EventStopped}
+				default:
+					log.Debugf("Ignoring unit sub state for service %s: %s", name, unit.SubState)


Shouldn't this be an error? What cases are missing here?

There are a few sub states we ignore because they are not relevant to our needs:

post-start

post-stop

pre-start
...
The ones we capture are the ones we want to take action.

eloycoto · 2022-08-26T09:58:32Z

internal/service/systemd.go

@@ -267,7 +262,8 @@ func (s *systemd) Stop() error {
 }

 func (s *systemd) Enable() error {
-	conn, err := newDbusConnection(s.Rootless)
+	log.Debugf("Enabling service %s", s.Name)


Enabling systemd service %v

sounds good.

done with %s

eloycoto · 2022-08-26T09:58:46Z

internal/service/systemd.go

@@ -278,7 +274,8 @@ func (s *systemd) Enable() error {
 }

 func (s *systemd) Disable() error {
-	conn, err := newDbusConnection(s.Rootless)
+	log.Debugf("Disabling service %s", s.Name)


Disabling systemd service

sounds good

eloycoto · 2022-08-26T09:59:19Z

internal/workload/podman/podman.go

@@ -15,9 +15,9 @@ import (
 	"github.com/blang/semver"
 	"github.com/go-openapi/swag"
 	"github.com/project-flotta/flotta-device-worker/internal/service"
+	api "github.com/project-flotta/flotta-device-worker/internal/workload/api"


this alias is not needed.

acknowledged

eloycoto · 2022-08-26T10:01:29Z

internal/workload/wrapper.go

+			log.Infof("Service for workload %s started", event.WorkloadName)
+			report, err := w.podManager.GetPodReportForPodName(event.WorkloadName)
+			if err != nil {
+				log.Errorf("unable to get pod report for workload %s:%v", event.WorkloadName, err)


I will workload '%s' as line 364

eloycoto · 2022-08-26T10:01:54Z

internal/workload/wrapper.go

+				observer.WorkloadStarted(event.WorkloadName, []*podman.PodReport{report})
+			}
+		case service.EventStopped:
+			log.Infof("Service for workload %s stopped", event.WorkloadName)


* Moved event listener instance and initialization to cmd.go main * Added a file system watcher to the systemd enabled services directory to be notified of new services from being enabled/disabled so that the event listener can track their status * Encapsulated the code to listen to service events generated by the systemd event listener so that it is called at the last line of the cmd.go#main function to make sure all observers are ready before start processing the service events

…n debug

…ceived to avoid potential race condition between file system event and dbus event

…vent filtering

jordigilh · 2022-09-23T15:35:12Z

@eloycoto I've addressed some of your comments, there are a few that I've replied. PTAL when you have spare time.

jordigilh requested review from masayag, eloycoto and machacekondra July 29, 2022 00:23

jordigilh force-pushed the test_podman_events branch from 9e198e5 to cb3229e Compare July 29, 2022 00:42

jordigilh changed the title ~~Migrate to use systemd events~~ [WIP] Migrate to use systemd events Jul 29, 2022

jordigilh changed the title ~~[WIP] Migrate to use systemd events~~ Migrate to use systemd events Jul 29, 2022

tupyy reviewed Aug 1, 2022

View reviewed changes

internal/service/event_listener.go Outdated Show resolved Hide resolved

tupyy reviewed Aug 1, 2022

View reviewed changes

internal/service/event_listener.go Outdated Show resolved Hide resolved

tupyy reviewed Aug 1, 2022

View reviewed changes

internal/service/systemd.go Outdated Show resolved Hide resolved

jordigilh force-pushed the test_podman_events branch from aae74c6 to c6b74ca Compare August 1, 2022 15:09

masayag reviewed Aug 2, 2022

View reviewed changes

jordigilh force-pushed the test_podman_events branch from 3a6a7c8 to 4427bfb Compare August 4, 2022 01:50

jordigilh force-pushed the test_podman_events branch 7 times, most recently from bb407e0 to 362dcd5 Compare August 4, 2022 20:03

masayag reviewed Aug 4, 2022

View reviewed changes

cmd/device-worker/main.go Outdated Show resolved Hide resolved

masayag approved these changes Aug 5, 2022

View reviewed changes

jordigilh force-pushed the test_podman_events branch from 362dcd5 to 33657e0 Compare August 8, 2022 17:21

tupyy reviewed Aug 8, 2022

View reviewed changes

jordigilh force-pushed the test_podman_events branch 3 times, most recently from d14c973 to c825ed8 Compare August 8, 2022 20:23

eloycoto reviewed Aug 26, 2022

View reviewed changes

eloycoto requested changes Aug 26, 2022

View reviewed changes

jordigilh added 12 commits September 23, 2022 10:29

Moving to systemd events to detect changes in service status

a4a3b5f

Refactor systemd functions

beecc65

Changes due to golint run

eb02092

Refactored event listener based on feedback

9576b12

Minimal refactor and cosmetic changes based on feedback

cced29f

Changed podman-auto-update to use userBus

3ee2afe

Fix svc not being deleted from services.json

7ed1508

Added Stringer() interface to observers so that they list correctly i…

882b186

…n debug

Process the error from stopping the service

c9929b9

Remove service from systemd watch filter when dbus remove event is re…

6b04ac2

…ceived to avoid potential race condition between file system event and dbus event

Use workload from device config as source of truth for dbus service e…

d263eb7

…vent filtering

jordigilh force-pushed the test_podman_events branch from c825ed8 to 7c39f0a Compare September 23, 2022 15:34

jordigilh force-pushed the test_podman_events branch from 7c39f0a to 20e0fb5 Compare September 23, 2022 15:38

Added more error verbosity

13b2b9e

jordigilh force-pushed the test_podman_events branch from 20e0fb5 to 13b2b9e Compare September 23, 2022 15:47

Migrate to use systemd events #217

Are you sure you want to change the base?

Migrate to use systemd events #217

Conversation

jordigilh commented Jul 29, 2022 • edited Loading

jordigilh commented Jul 29, 2022

jordigilh commented Jul 29, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eloycoto commented Aug 2, 2022

jordigilh commented Aug 2, 2022 • edited Loading

eloycoto commented Aug 2, 2022

jordigilh commented Aug 2, 2022 • edited Loading

eloycoto commented Aug 2, 2022

jordigilh commented Aug 2, 2022

jordigilh commented Aug 4, 2022 • edited Loading

jordigilh commented Aug 4, 2022

jordigilh commented Aug 8, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jordigilh Sep 23, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jordigilh commented Sep 23, 2022

jordigilh commented Jul 29, 2022 •

edited

Loading

jordigilh commented Aug 2, 2022 •

edited

Loading

jordigilh commented Aug 2, 2022 •

edited

Loading

jordigilh commented Aug 4, 2022 •

edited

Loading

jordigilh commented Aug 8, 2022 •

edited

Loading

jordigilh Sep 23, 2022 •

edited

Loading